time read, filter and writer operations (#1150)

* time read, filter and writer operations

when using -D > 0.

* take stray dog to the pound.

diff --git a/main.cc b/main.cc
index 9e90077ab1adaeb4591ba8d2b0ed76355af39f89..3c20a5d7bb485cf308ba62e394f1e9820c9684f5 100644 (file)
--- a/main.cc
+++ b/main.cc
@@ -24,6 +24,7 @@
 #include <cstring>                    // for strcmp
 
 #include <QCoreApplication>           // for QCoreApplication
+#include <QElapsedTimer>              // for QElapsedTimer
 #include <QFile>                      // for QFile
 #include <QIODevice>                  // for QIODevice::ReadOnly
 #include <QLocale>                    // for QLocale
@@ -61,6 +62,8 @@ static constexpr bool DEBUG_LOCALE = false;
 // be careful not to advance argn passed the end of the list, i.e. ensure argn < qargs.size()
 #define FETCH_OPTARG qargs.at(argn).size() > 2 ? QString(qargs.at(argn)).remove(0,2) : qargs.size()>(argn+1) ? qargs.at(++argn) : QString()
 
+static QElapsedTimer timer;
+
 class QargStackElement
 {
 public:
@@ -247,6 +250,9 @@ private:
 static void
 run_reader(Vecs::fmtinfo_t& ivecs, const QString& fname)
 {
+  if (global_opts.debug_level > 0)  {
+    timer.start();
+  }
   start_session(ivecs.fmtname, fname);
   if (ivecs.isDynamic()) {
     ivecs.fmt = ivecs.factory(fname);
@@ -268,11 +274,18 @@ run_reader(Vecs::fmtinfo_t& ivecs, const QString& fname)
     ivecs->read();
     ivecs->rd_deinit();
   }
+  if (global_opts.debug_level > 0)  {
+    Warning().noquote() << QStringLiteral("%1: reader %2 took %3 seconds.")
+                        .arg(MYNAME, ivecs.fmtname, QString::number(timer.elapsed()/1000.0, 'f', 3));
+  }
 }
 
 static void
 run_writer(Vecs::fmtinfo_t& ovecs, const QString& ofname)
 {
+  if (global_opts.debug_level > 0)  {
+    timer.start();
+  }
   if (ovecs.isDynamic()) {
     ovecs.fmt = ovecs.factory(ofname);
     Vecs::init_vec(ovecs.fmt);
@@ -293,6 +306,10 @@ run_writer(Vecs::fmtinfo_t& ovecs, const QString& ofname)
     ovecs->write();
     ovecs->wr_deinit();
   }
+  if (global_opts.debug_level > 0)  {
+    Warning().noquote() << QStringLiteral("%1: writer %2 took %3 seconds.")
+                        .arg(MYNAME, ovecs.fmtname, QString::number(timer.elapsed()/1000.0, 'f', 3));
+  }
 }
 
 static int
@@ -451,6 +468,9 @@ run(const char* prog_name)
       filter = FilterVecs::Instance().find_filter_vec(argument);
 
       if (filter) {
+        if (global_opts.debug_level > 0)  {
+          timer.start();
+        }
         if (filter.isDynamic()) {
           filter.flt = filter.factory();
           FilterVecs::init_filter_vec(filter.flt);
@@ -471,6 +491,10 @@ run(const char* prog_name)
           filter->deinit();
           FilterVecs::free_filter_vec(filter.flt);
         }
+        if (global_opts.debug_level > 0)  {
+          Warning().noquote() << QStringLiteral("%1: filter %2 took %3 seconds.")
+                              .arg(MYNAME, filter.fltname, QString::number(timer.elapsed()/1000.0, 'f', 3));
+        }
       }  else {
         fatal("Unknown filter '%s'\n",qPrintable(argument));
       }